I would like to see a benchmark included with this PR.

Before:

pkgtree - test-bench! ❯ go test -bench=. -benchmem
BenchmarkListPackages-4             2000           1245467 ns/op          215346 B/op       1263 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      2.626s

After:

pkgtree - fastwalk ❯ go test -bench=. -benchmem
BenchmarkListPackages-4             2000           1267992 ns/op          142744 B/op       1171 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      2.675s

So, no significant changes :(

So, no significant changes :(

Let's do some profiling then and figure out where the bottleneck is.

It's also possible (probable?) that the cases we have in _testdata are so small that walking the file tree isn't where we're spending much time. I guess I could do a bench on the whole dep tree?

Benched on the whole dep tree, appears fastwalk is slower:

Old:

pkgtree - bench-dep! ❯ go test -bench=. -benchmem -benchtime=5s
BenchmarkListPackages-4              500          17995996 ns/op         4049772 B/op      19074 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      10.810s

New:

pkgtree - fastwalk ❯ go test -bench=. -benchmem -benchtime=5s
BenchmarkListPackages-4              300          23751257 ns/op         6050304 B/op      31457 allocs/op
PASS
ok      github.com/golang/dep/internal/gps/pkgtree      9.620s

Clickable SVGs from go-torch:

Old: https://sca.ndella.com/old.svg

New: https://sca.ndella.com/new.svg

Yep, looks like it's the filepath.Glob() and the stat we just added that are eating most of the gains. It strikes me that both of those should be unnecessary, now. Lemme sketch that out...

Sounds good. The bench-dep branch is pushed to my personal repo which is head of master + the benchmark for the dep repo. This branch has the same benchmark, but with the fastwalk change.

Something like this...

1. Move a bit of the logic from the walkFn up into the fastwalker - it should only be called for directories (DT_DIR).
2. When it's called, pass it a slice of name + os.FileMode tuples that represent only the files/DT_REG - we know, at least for now, that we're not touching symlinks.
3. Refactor fillPackages to receive that tuple slice. That should obviate the need for both the glob and that initial stat.

his branch has the same benchmark, but with the fastwalk change.

Excellent - we definitely can't introduce this amount of complexity without benchmarks to justify it.

Cool, I'm done for the day, I'll take a look at optimizing this tomorrow.

Hmm, I've been playing around with various refactors for a while now but keep getting chicken-and-egged as far as having directory listings ready with the directory name. Going to keep thinking on this.

Ya, I'm new to this project, this was just a task @sdboyer said was worth investigating. It may not be worth the effort, but I'm not really in the best position to say. Do we currently have end-to-end benchmarks on what "typical" behavior should be?

Do we currently have end-to-end benchmarks on what "typical" behavior should be?

I started in that direction with benchmarks in #558, but the existing test cases aren't particularly interesting. More complex integration test cases would be neat, or maybe an alternative way to run or compile the dep cmd to dump timing and profile info. The latter might be more broadly useful, especially for investigating cases in the wild (e.g. "Why is dep so slow on my project?" "Run it again with the '-foo' flag to dump profile info and we'll find out"). I've been meaning to look into this more and write something up.

I recompiled dep with runtime/pprof as so:

dep - master! ❯ git --no-pager diff
diff --git i/cmd/dep/main.go w/cmd/dep/main.go
index ae4cf3a..306f810 100644
--- i/cmd/dep/main.go
+++ w/cmd/dep/main.go
@@ -10,8 +10,10 @@ import (
        "flag"
        "fmt"
        "io"
+       "io/ioutil"
        "log"
        "os"
+       "runtime/pprof"
        "strings"
        "text/tabwriter"

@@ -29,6 +31,13 @@ type command interface {
 }

 func main() {
+       fn, err := ioutil.TempFile("", "pprof")
+       if err != nil {
+               panic(err)
+       }
+       fmt.Println("PProf: fn", fn.Name())
+       pprof.StartCPUProfile(fn)
+
        wd, err := os.Getwd()
        if err != nil {
                fmt.Fprintln(os.Stderr, "failed to get working directory", err)
@@ -41,7 +50,9 @@ func main() {
                WorkingDir: wd,
                Env:        os.Environ(),
        }
-       os.Exit(c.Run())
+       code := c.Run()
+       pprof.StopCPUProfile()
+       os.Exit(code)
 }

Looks like a lot of time spent in crypto/loadSystemRoots

The flame graph is here (you can click in to select segments): https://sca.ndella.com/zap-dep-init.svg -- you can see about 20% of the time is spent in gps.solve of which almost all is listPackages. This is from running dep init -v on github.com/uber-go/zap:

PProf: fn /var/folders/b3/pnm730v50fg2ms_mtbrxkzwc0000gn/T/pprof612691900
dep: Finding dependencies for "github.com/uber-go/zap"...
dep: Found 9 dependencies.
Searching GOPATH for projects...
dep: Building dependency graph...
dep: Found import of "github.com/Sirupsen/logrus", analyzing...
  Using ^0.8.7 as constraint for direct dep github.com/Sirupsen/logrus
  Locking in v0.8.7 (418b41d) for direct dep github.com/Sirupsen/logrus
dep: Found import of "github.com/apex/log", analyzing...
dep: Could not determine version for "github.com/apex/log", omitting from generated manifest
dep: Found import of "github.com/go-kit/kit/log", analyzing...
dep: Could not determine version for "github.com/go-kit/kit", omitting from generated manifest
dep: Found import of "github.com/stretchr/testify/assert", analyzing...
  Using e3a8ff8 as hint for direct dep github.com/stretchr/testify
dep: Found import of "github.com/uber-common/bark", analyzing...
  Using d52ffa0 as hint for direct dep github.com/uber-common/bark
dep: Found import of "github.com/uber-go/atomic", analyzing...
  Using master as constraint for direct dep github.com/uber-go/atomic
  Locking in master (9e99152) for direct dep github.com/uber-go/atomic
dep: Found import of "gopkg.in/inconshreveable/log15.v2", analyzing...
dep: Could not determine version for "gopkg.in/inconshreveable/log15.v2", omitting from generated manifest
dep: Analyzing transitive imports...
dep: Analyzing "github.com/Sirupsen/logrus"...
dep: Analyzing "github.com/apex/log/handlers/json"...
dep: Analyzing "github.com/stretchr/testify/assert"...
dep: Analyzing "github.com/davecgh/go-spew/spew"...
  Locking in  (5215b55) for transitive dep github.com/davecgh/go-spew
dep: Analyzing "github.com/pmezard/go-difflib/difflib"...
  Locking in  (e8554b8) for transitive dep github.com/pmezard/go-difflib
dep: Analyzing "github.com/stretchr/testify/require"...
dep: Analyzing "github.com/uber-common/bark"...
dep: Analyzing "github.com/cactus/go-statsd-client/statsd"...
  Locking in  (dc93b85) for transitive dep github.com/cactus/go-statsd-client
dep: Analyzing "gopkg.in/inconshreveable/log15.v2"...
dep: Analyzing "github.com/apex/log"...
dep: Analyzing "github.com/go-kit/kit/log"...
dep: Analyzing "github.com/uber-go/atomic"...
Using network for remaining projects...
dep: Solving...
Root project is "github.com/uber-go/zap"
 7 transitively valid internal packages
 9 external packages imported from 7 projects
(0)   ✓ select (root)
(1)     ? attempt github.com/Sirupsen/logrus with 1 pkgs; at least 1 versions to try
(1)         try github.com/Sirupsen/logrus@v0.8.7
(1)     ✓ select github.com/Sirupsen/logrus@v0.8.7 w/1 pkgs
(2)     ? attempt github.com/stretchr/testify with 2 pkgs; at least 1 versions to try
(2)         try github.com/stretchr/testify@e3a8ff8ce36581f87a15341206f205b1da467059
(2)     ✓ select github.com/stretchr/testify@e3a8ff8ce36581f87a15341206f205b1da467059 w/2 pkgs
(3)     ? attempt github.com/davecgh/go-spew with 1 pkgs; at least 1 versions to try
(3)         try github.com/davecgh/go-spew@5215b55f46b2b919f50a1df0eaa5886afe4e3b3d
(3)     ✓ select github.com/davecgh/go-spew@5215b55f46b2b919f50a1df0eaa5886afe4e3b3d w/1 pkgs
(4)     ? attempt gopkg.in/inconshreveable/log15.v2 with 1 pkgs; 12 versions to try
(4)         try gopkg.in/inconshreveable/log15.v2@v2.11
(4)     ✓ select gopkg.in/inconshreveable/log15.v2@v2.11 w/3 pkgs
(5)     ? attempt github.com/pmezard/go-difflib with 1 pkgs; at least 1 versions to try
(5)         try github.com/pmezard/go-difflib@e8554b8641db39598be7f6342874b958f12ae1d4
(5)     ✓ select github.com/pmezard/go-difflib@e8554b8641db39598be7f6342874b958f12ae1d4 w/1 pkgs
(6)     ? attempt github.com/apex/log with 2 pkgs; 1 versions to try
(6)         try github.com/apex/log@master
(6)     ✓ select github.com/apex/log@master w/2 pkgs
(7)     ? attempt github.com/uber-go/atomic with 1 pkgs; at least 1 versions to try
(7)         try github.com/uber-go/atomic@master
(7)     ✓ select github.com/uber-go/atomic@master w/1 pkgs
(8)     ? attempt github.com/go-kit/kit with 1 pkgs; 10 versions to try
(8)         try github.com/go-kit/kit@v0.4.0
(8)     ✓ select github.com/go-kit/kit@v0.4.0 w/1 pkgs
(9)     ? attempt github.com/uber-common/bark with 1 pkgs; at least 1 versions to try
(9)         try github.com/uber-common/bark@d52ffa061726911f47fcd3d9e8b9b55f22794772
(9)     ✓ select github.com/uber-common/bark@d52ffa061726911f47fcd3d9e8b9b55f22794772 w/1 pkgs
(10)  ? attempt github.com/cactus/go-statsd-client with 1 pkgs; at least 1 versions to try
(10)      try github.com/cactus/go-statsd-client@dc93b8587d799a204e96175505fff9678a8ec3e1
(10)  ✓ select github.com/cactus/go-statsd-client@dc93b8587d799a204e96175505fff9678a8ec3e1 w/1 pkgs
(11)  ? attempt github.com/go-logfmt/logfmt with 1 pkgs; 5 versions to try
(11)      try github.com/go-logfmt/logfmt@v0.3.0
(11)  ✓ select github.com/go-logfmt/logfmt@v0.3.0 w/1 pkgs
(12)  ? attempt github.com/kr/logfmt with 1 pkgs; 2 versions to try
(12)      try github.com/kr/logfmt@master
(12)  ✓ select github.com/kr/logfmt@master w/1 pkgs
(13)  ? attempt github.com/go-stack/stack with 1 pkgs; 12 versions to try
(13)      try github.com/go-stack/stack@v1.5.3
(13)  ✓ select github.com/go-stack/stack@v1.5.3 w/1 pkgs
(14)  ? attempt github.com/pkg/errors with 1 pkgs; 11 versions to try
(14)      try github.com/pkg/errors@v0.8.0
(14)  ✓ select github.com/pkg/errors@v0.8.0 w/1 pkgs
(15)  ? attempt github.com/mattn/go-colorable with 1 pkgs; 9 versions to try
(15)      try github.com/mattn/go-colorable@v0.0.7
(15)  ✓ select github.com/mattn/go-colorable@v0.0.7 w/1 pkgs
(16)  ? attempt github.com/mattn/go-isatty with 1 pkgs; 4 versions to try
(16)      try github.com/mattn/go-isatty@v0.0.2
(16)  ✓ select github.com/mattn/go-isatty@v0.0.2 w/1 pkgs
(17)  ? attempt golang.org/x/sys with 1 pkgs; 1 versions to try
(17)      try golang.org/x/sys@master
(17)  ✓ select golang.org/x/sys@master w/1 pkgs
  ✓ found solution with 21 packages from 17 projects

Solver wall times by segment:
              b-gmal: 3.506980319s
         b-list-pkgs: 3.144245245s
     b-source-exists: 1.106882088s
     b-list-versions: 332.315608ms
  b-deduce-proj-root: 125.590738ms
             satisfy:   3.875204ms
         select-atom:   2.641545ms
         select-root:     689.64µs
            new-atom:    584.485µs
               other:     76.106µs

  TOTAL: 8.223880978s

  Using ^0.4.0 as constraint for direct dep github.com/go-kit/kit
  Locking in v0.4.0 (fadad6f) for direct dep github.com/go-kit/kit
  Locking in v1.5.3 (7a2f196) for transitive dep github.com/go-stack/stack
  Locking in v0.0.2 (fc9e8d8) for transitive dep github.com/mattn/go-isatty
  Using ^2.11.0 as constraint for direct dep gopkg.in/inconshreveable/log15.v2
  Locking in v2.11 (b105bd3) for direct dep gopkg.in/inconshreveable/log15.v2
  Locking in v0.3.0 (390ab79) for transitive dep github.com/go-logfmt/logfmt
  Locking in v0.8.0 (645ef00) for transitive dep github.com/pkg/errors
  Using master as constraint for direct dep github.com/apex/log
  Locking in master (7259ed7) for direct dep github.com/apex/log
  Locking in v0.0.7 (d228849) for transitive dep github.com/mattn/go-colorable
  Locking in master (a2e06a1) for transitive dep golang.org/x/sys
  Locking in master (b84e30a) for transitive dep github.com/kr/logfmt
Old vendor backed up to /Users/aiden/src/go/src/github.com/uber-go/zap/vendor-20170518163154
dep: Writing manifest and lock files.

Before you invest more time in this, is it worth profiling dep to determine
if there is a bottleneck, and where it is?

Definitely, always the prerequisite question. There were a buncha things that led me to suggesting this as an area we might investigate optimizing, though the most bottom-bedrock numbers are actually ones done by @bradfitz in comparing goimports' performance against plain filepath.Walk(), in the context of a discussion about (I think) guru. Or maybe gomvpkg. Something that Alan works on. Unfortunately, I can't remember exactly where I saw it. IIRC, the logic we're working on incorporating here cut running time on large trees by...half? idk. Something nontrivial.

However, teasing out just how significant that is for dep can be hard; indeed, @jmank88's first pass at some benchmarks demonstrate how tricky benchmarking can be here. So, I figure it's probably useful for me to lay out some organizing principles that may be helpful both here, and in constructing benchmarks more generally.

1. First, the FAQ has some useful background.
2. For now, the performance issues we care about are the low-n, high-k factors; there's another set of considerations related to the actual cost of purely in-memory solving, when the solver goes exponential. That's a wholly different class of problem; this issue is really about reducing k, not reducing n.
3. There are five main classes of ops that we do with high k, all ultimately because they involve IO. General metrics on these are dumped in -v output under the Solver wall times by segment: header. Almost all of these are cacheable, many permanently so.
   1. SourceManager.ListVersions(), which retrieves a current list of available versions from an upstream source (generally network IO)
   2. SourceManager.ListPackages(), which statically analyzes a go code tree, and is the focus of this issue (disk IO)
   3. SourceManager.GetManifestAndLock(), which reads in the contents of e.g. Gopkg.toml and Gopkg.lock (disk IO)
   4. SourceManager.DeduceProjectRoot() can trigger go get HTTP metadata retrieval (network IO)
   5. SourceManager.ExportProject(), which writes out a copy of a project at a given version to an arbitrary location (disk IO)
4. There are three main phases for each dep command; they must occur serially (though earlier phases can sometimes initialize work in the background for later ones). The current high costs in each area are mostly constituted from one of the preceding five types of IO.
   1. Initial project scan
   2. Solving
   3. Writing out vendor/

Describing these in the reverse of the order in which they actually occur is the best way to have them make sense.

Writing out vendor/ is mostly separate from the others; for now, we just sloppily reconstruct an entire vendor dir from scratch out of the source cache. Once #121 is implemented, we'll have the opportunity to make this more sophisticated. This phase is generally, though not entirely, what happens with the gps.Solution returned from a gps.Solver.Solve() call.

The solving phase is everything under gps.Solver.Solve(), which can include an enormous number of calls to each the OI types 1-4. However, once #431 is implemented and we're storing such results permanently, these costs amortize to zero.

The initial phase is the most varied and complicated. For the purposes of this issue, though, what really matters is that ListPackages() must be called in order to construct the local package list. And, because the current project is the code that's subject to change, there's little point in caching it a la #431 (in fact, the API is designed such that doing so is nigh-impossible). Consequently, literally every single dep run will need to run this code in order to scan the current project; for no-op runs (i.e., input hashes match, so no need for phases 2 and 3), I believe this ListPackages() logic will be almost entirely determinative of the minimum running time.

(BTW, @jmank88, this "initial loading" cost is probably one good area to focus some benchmarks on.)

So: once persistent caching is in place, this scan is likely to become one of if not the largest consistent bottleneck in the program. And it's still worth working on now, because it's a considerable part of the bottleneck we currently see, as well.

Unfortunately, I can't remember exactly where I saw it

Maybe you're thinking of golang/go#16399

My vague recollection is seeing it in a discussion that was more specifically comparing it against guru/gomvpkg/something Alan works on. But it doesn't really matter, as golang/go#16399 is definitely dealing with the same underlying problem, and is more exhaustive than what I remember seeing. Thanks for the pointer!

Wow, Sam, your thorough explanations are quite helpful and thoughtful! Thanks for that.

I'm definitely convinced that this path needs optimizing, I think I just need to work on a cleanroom implementation rather than trying to retrofit it into the existing structure. Hopefully I will have time to do that this week.

I haven't forgetten about this, just been sick. Hopefully will be able to resume work tomorrow

no worries, thanks for update 😄

feel better!

bump, just checking in

yo, I am alive and back from sickness/vacation, will look at this again today

Going to have to abandon this for now -- I just switched teams and no longer have free time to work on dep. I may re-open if nobody else picks this up, but that would be in the 2-3 week timeframe :(

😢 understood - thanks for the clear communication and not just leaving it sit!